Skip to content
This repository has been archived by the owner on Feb 24, 2024. It is now read-only.

made request logger the last middleware #2334

Merged
merged 1 commit into from
Oct 1, 2022

Conversation

sio4
Copy link
Member

@sio4 sio4 commented Sep 29, 2022

This is a fix for #2300. See the issue for the issue details and initial investigation.

fixes #2300

The current sequence and tasks for each step are the following:

  1. RequestLoggerFunc pre-tasks (no condition)
    • set requester_id
    • set request_id
    • set log field for request_id
    • set start time
  2. Other middleware tasks and the original handler
  3. RequestLoggerFunc defer-tasks (no condition)
    • log
  4. PanicHandler defer-tasks (when only panic happens)
    • emit an error event
    • call error handler
  5. defaultErrorMiddleware post-tasks (only when error returned)
    • set status
    • emit an error event
    • call error handler

They are mostly orthogonal so the current order could be changed without side effects. Since step 5 sets the missing status for the response, moving step 3 next to step 5 can be the solution (the change of this PR).

The middleware stack will be fixed like:

-> http://127.0.0.1:3000/
        github.com/gobuffalo/buffalo.RequestLoggerFunc
        github.com/gobuffalo/buffalo.*App.defaultErrorMiddleware
        github.com/gobuffalo/buffalo.*App.PanicHandler
        github.com/gobuffalo/mw-forcessl.Middleware.func1
        github.com/gobuffalo/mw-paramlogger.ParameterLogger
        github.com/gobuffalo/mw-csrf.glob..func1
        github.com/gobuffalo/mw-i18n/v2.*Translator.Middleware.func1

As a result of this PR, the logs will be changed as the followings:

when the handler returns a non-nil error without the status code

DEBU[2022-09-29T19:36:02+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T19:36:02+09:00] /error/ db=0s duration="872.947µs" human_size="0 B" method=GET params="{}" path=/error/ request_id=39faa49026241a150ddc-068b8fd32563ed5d3a39 size=0 status=0
ERRO[2022-09-29T19:36:02+09:00] error message db=0s duration="872.947µs" human_size="0 B" method=GET params="{}" path=/error/ request_id=39faa49026241a150ddc-068b8fd32563ed5d3a39 size=0 status=500

become

DEBU[2022-09-29T20:03:55+09:00] --- ROLLBACK Transaction ---
ERRO[2022-09-29T20:03:55+09:00] error message db=0s params="{}" request_id=1230fbcfbd29dc2db42f-52552052f7bdd5078988 status=500
INFO[2022-09-29T20:03:55+09:00] /error/ db=0s duration=1.21633ms human_size="33 kB" method=GET params="{}" path=/error/ request_id=1230fbcfbd29dc2db42f-52552052f7bdd5078988 size=33237 status=500

See the size and status in the INFO log. The size represents the size of the error response set by the (default) error handler.

for a similar situation but panic

DEBU[2022-09-29T19:36:30+09:00] --- ROLLBACK Transaction (inner function panic) ---
INFO[2022-09-29T19:36:30+09:00] /panic/ db=0s duration="729.912µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=f6165b3ef40b5c6f9dd1-2ca323c6021c6312edb7 size=0 status=0
ERRO[2022-09-29T19:36:30+09:00] transaction was rolled back due to inner panic db=0s duration="729.912µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=f6165b3ef40b5c6f9dd1-2ca323c6021c6312edb7 size=0 status=500

become

DEBU[2022-09-29T20:04:52+09:00] --- ROLLBACK Transaction (inner function panic) ---
ERRO[2022-09-29T20:04:52+09:00] transaction was rolled back due to inner panic db=0s params="{}" request_id=6da003dc284dd63ec0e3-f85852dd00b8b481ee0c status=500
INFO[2022-09-29T20:04:52+09:00] /panic/ db=0s duration=3.044308ms human_size="33 kB" method=GET params="{}" path=/panic/ request_id=6da003dc284dd63ec0e3-f85852dd00b8b481ee0c size=33279 status=500

as the same as above, the INFO line has the real size and status code.
(In this case, pop middleware catch the panic by the recent fix gobuffalo/pop#775)

See the other cases related to this change

when the handler properly renders the result (same for 200, 404, 500,...):

DEBU[2022-09-29T19:35:37+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T19:35:37+09:00] /st500/ db=0s duration="845.08µs" human_size="5 B" method=GET params="{}" path=/st500/ render="164.896µs" request_id=0f11c9e00d3854e17643-c4d7f63b41164b598efa size=5 status=500

DEBU[2022-09-29T20:03:39+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T20:03:39+09:00] /st500/ db=0s duration="523.998µs" human_size="5 B" method=GET params="{}" path=/st500/ render="118.349µs" request_id=e425ccd21bf787e6ea2f-412075fb1af9ba11eb2d size=5 status=500

when the app does not use pop middleware which catches the inner panic

INFO[2022-09-29T19:43:16+09:00] /panic/ duration="927.039µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=656808efa63c4a58673d-a5bbbd3a6f01ada91d60 size=0 status=0
ERRO[2022-09-29T19:43:16+09:00] panic message duration="927.039µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=656808efa63c4a58673d-a5bbbd3a6f01ada91d60 size=0 status=500

ERRO[2022-09-29T20:06:30+09:00] panic message params="{}" request_id=91724c36f9b7270dd929-ff17f850b8473effdf2d status=500
INFO[2022-09-29T20:06:30+09:00] /panic/ duration=2.414179ms human_size="33 kB" method=GET params="{}" path=/panic/ request_id=91724c36f9b7270dd929-ff17f850b8473effdf2d size=33089 status=500

This is the same as error situation.

still problematic (when the handler returns nil but the status code is still not set properly)

See details in gobuffalo/buffalo-pop#19

$ curl -v http://localhost:3000/nil
< HTTP/1.1 200 OK

DEBU[2022-09-29T20:03:15+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T20:03:15+09:00] /nil/ db=0s duration="714.435µs" human_size="0 B" method=GET params="{}" path=/nil/ request_id=8be7a1205504406b5565-bbd6a73e06937b175a90 size=0 status=0

@sio4 sio4 added the bug Something isn't working label Sep 29, 2022
@sio4 sio4 added this to the v1.1.0 milestone Sep 29, 2022
@sio4 sio4 self-assigned this Sep 29, 2022
@sio4 sio4 requested a review from a team as a code owner September 29, 2022 12:07
@sio4 sio4 merged commit 9885e24 into v1 Oct 1, 2022
@sio4 sio4 deleted the make-requestlogger-the-last-middleware branch October 6, 2022 17:31
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

HTTP response code, err returned by request handlers, and middlewares
1 participant